// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.

#include <vespa/metrics/metrics.h>
#include <vespa/metrics/xmlwriter.h>
#include <vespa/metrics/jsonwriter.h>
#include <vespa/metrics/textwriter.h>
#include <vespa/metrics/printutils.h>
#include <vespa/metrics/state_api_adapter.h>
#include <vespa/vdstestlib/cppunit/macros.h>
#include <vespa/vespalib/stllike/asciistream.h>
#include <vespa/vespalib/data/slime/slime.h>
#include <vespa/vespalib/util/xmlstream.h>
#include <vespa/log/log.h>

LOG_SETUP(".test.metricmanager");

namespace metrics {

struct MetricManagerTest : public CppUnit::TestFixture {
    void testConsumerVisitor();
    void testSnapshots();
    void testPrintUtils();
    void testXmlOutput();
    void testJsonOutput();
    void jsonOutputSupportsMultipleDimensions();
    void jsonOutputCanNestDimensionsFromMultipleMetricSets();
    void jsonOutputCanHaveMultipleSetsWithSameName();
    void testTextOutput();
    void textOutputSupportsDimensions();
    void testUpdateHooks();

    CPPUNIT_TEST_SUITE(MetricManagerTest);
    CPPUNIT_TEST(testConsumerVisitor);
    CPPUNIT_TEST(testSnapshots);
    CPPUNIT_TEST(testPrintUtils);
    CPPUNIT_TEST(testXmlOutput);
    CPPUNIT_TEST(testJsonOutput);
    CPPUNIT_TEST(jsonOutputSupportsMultipleDimensions);
    CPPUNIT_TEST(jsonOutputCanNestDimensionsFromMultipleMetricSets);
    CPPUNIT_TEST(jsonOutputCanHaveMultipleSetsWithSameName);
    CPPUNIT_TEST(testTextOutput);
    CPPUNIT_TEST(textOutputSupportsDimensions);
    CPPUNIT_TEST(testUpdateHooks);
    CPPUNIT_TEST_SUITE_END();

public:
    // Ugly indirection hack caused by some tests using friended internals of
    // MetricManager that aren't accessible to "freestanding" fixtures. So we
    // get the test to do the necessary poking and prodding for us instead.
    void takeSnapshots(MetricManager& mm, time_t timeToProcess) {
        mm.takeSnapshots(mm.getMetricLock(), timeToProcess);
    }
};

CPPUNIT_TEST_SUITE_REGISTRATION(MetricManagerTest);

namespace {

struct SubMetricSet : public MetricSet
{
    DoubleValueMetric val1;
    DoubleValueMetric val2;
    SumMetric<DoubleValueMetric> valsum;

    SubMetricSet(const Metric::String & name, MetricSet* owner);
    ~SubMetricSet();
};


SubMetricSet::SubMetricSet(const Metric::String & name, MetricSet* owner)
    : MetricSet(name, "sub", "sub desc", owner, "sub"),
      val1("val1", "tag4 snaptest", "val1 desc", this),
      val2("val2", "tag5", "val2 desc", this),
      valsum("valsum", "tag4 snaptest", "valsum desc", this)
{
    valsum.addMetricToSum(val1);
    valsum.addMetricToSum(val2);
}
SubMetricSet::~SubMetricSet() { }

struct MultiSubMetricSet
{
    MetricSet set;
    LongCountMetric count;
    SubMetricSet a;
    SubMetricSet b;
    SumMetric<MetricSet> sum;

    MultiSubMetricSet(MetricSet* owner);
    ~MultiSubMetricSet();
};

MultiSubMetricSet::MultiSubMetricSet(MetricSet* owner)
    : set("multisub", "multisub", "", owner),
    count("count", "snaptest", "counter", &set),
    a("a", &set),
    b("b", &set),
    sum("sum", "snaptest", "", &set)
{
    sum.addMetricToSum(a);
    sum.addMetricToSum(b);
}
    MultiSubMetricSet::~MultiSubMetricSet() { }

struct TestMetricSet {
    MetricSet set;
    DoubleValueMetric val1;
    DoubleValueMetric val2;
    DoubleValueMetric val3;
    DoubleValueMetric val4;
    DoubleValueMetric val5;
    DoubleValueMetric val6;
    DoubleValueMetric val7;
    DoubleValueMetric val8;
    SubMetricSet val9;
    MultiSubMetricSet val10;

    TestMetricSet();
    ~TestMetricSet();
};

TestMetricSet::TestMetricSet()
    : set("temp", "test", "desc of test set"),
      val1("val1", "tag1", "val1 desc", &set),
      val2("val2", "tag1 tag2", "val2 desc", &set),
      val3("val3", "tag2 tag3", "val3 desc", &set),
      val4("val4", "tag3", "val4 desc", &set),
      val5("val5", "tag2", "val5 desc", &set),
      val6("val6", "tag4 snaptest", "val6 desc", &set),
      val7("val7", "", "val7 desc", &set),
      val8("val8", "tag6", "val8 desc", &set),
      val9("sub", &set),
      val10(&set)
{ }

TestMetricSet::~TestMetricSet() { }


struct MetricNameVisitor : public MetricVisitor {
    std::ostringstream ost;
    bool debug;

    MetricNameVisitor(bool debug_ = false) : debug(debug_) {}

    bool visitMetricSet(const MetricSet& metricSet, bool autoGenerated) override {
        if (debug) {
            ost << "<" << (autoGenerated ? "*" : "")
                << metricSet.getPath() << ">\n";
        }
        return true;
    }
    void doneVisitingMetricSet(const MetricSet& metricSet) override {
        if (debug) {
            ost << "</" << metricSet.getPath() << ">\n";
        }
    }

    bool visitMetric(const Metric& m, bool autoGenerated) override {
        ost << (autoGenerated ? "*" : "") << m.getPath() << "\n";
        return true;
    }

    std::string toString() const { return ost.str(); }
};

}

namespace {
    std::pair<std::string, std::string> getMatchedMetrics(
                                            const vespalib::string& config)
    {
        FastOS_ThreadPool pool(256 * 1024);
        TestMetricSet mySet;
        MetricManager mm;
        mm.registerMetric(mm.getMetricLock(), mySet.set);
        mm.init(config, pool);
        MetricNameVisitor visitor;

        /** Take a copy to verify clone works.
        std::list<Metric::SP> ownerList;
        MetricSet::UP copy(dynamic_cast<MetricSet*>(
                    mm.getMetrics().clone(ownerList)));
        mm.visit(*copy, visitor, "consumer");
        */

        MetricLockGuard g(mm.getMetricLock());
        mm.visit(g, mm.getActiveMetrics(g), visitor, "consumer");
        MetricManager::ConsumerSpec::SP consumerSpec(
                mm.getConsumerSpec(g, "consumer"));
        return std::pair<std::string, std::string>(
                visitor.toString(),
                consumerSpec.get() ? consumerSpec->toString()
                                   : "Non-existing consumer");
    }
}

#define ASSERT_CONSUMER_MATCH(name, expected, config) \
{ \
    std::pair<std::string, std::string> consumerMatch( \
                                            getMatchedMetrics(config)); \
    CPPUNIT_ASSERT_EQUAL_MSG(name + std::string(": ") + consumerMatch.second, \
                             "\n" + expected, "\n" + consumerMatch.first); \
}

void MetricManagerTest::testConsumerVisitor()
{
        // Add one tag and a name, check that we get all three.
    ASSERT_CONSUMER_MATCH("testAddTagAndName", std::string(
            "temp.val1\n"
            "temp.val2\n"
            "temp.val4\n"
            "*temp.multisub.sum.val1\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] tag1\n"
            "consumer[0].addedmetrics[2]\n"
            "consumer[0].addedmetrics[0] temp.val4\n"
            "consumer[0].addedmetrics[1] temp.multisub.sum.val1\n"
    );
        // Add two tags, remove one
    ASSERT_CONSUMER_MATCH("testAddAndRemoveTag", std::string(
            "temp.val1\n"
            "temp.val4\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].tags[2]\n"
            "consumer[0].tags[0] tag1\n"
            "consumer[0].tags[1] tag3\n"
            "consumer[0].removedtags[1]\n"
            "consumer[0].removedtags[0] tag2\n"
    );
        // Test simple wildcards
    ASSERT_CONSUMER_MATCH("testWildCards", std::string(
            "temp.val1\n"
            "temp.val2\n"
            "temp.val3\n"
            "temp.val4\n"
            "temp.val5\n"
            "temp.val6\n"
            "temp.val7\n"
            "temp.val8\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].addedmetrics[1]\n"
            "consumer[0].addedmetrics[0] temp.*\n"
            "consumer[0].removedmetrics[2]\n"
            "consumer[0].removedmetrics[0] temp.sub.*\n"
            "consumer[0].removedmetrics[1] temp.multisub.*\n"
    );
        // Test more wildcards
    ASSERT_CONSUMER_MATCH("testWildCards2", std::string(
            "temp.sub.val1\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].addedmetrics[1]\n"
            "consumer[0].addedmetrics[0] temp.*.val1\n"
    );
        // test adding all
    ASSERT_CONSUMER_MATCH("testAddAll", std::string(
            "metricmanager.periodichooklatency\n"
            "metricmanager.snapshothooklatency\n"
            "metricmanager.resetlatency\n"
            "metricmanager.snapshotlatency\n"
            "metricmanager.sleeptime\n"
            "temp.val1\n"
            "temp.val2\n"
            "temp.val3\n"
            "temp.val4\n"
            "temp.val5\n"
            "temp.val6\n"
            "temp.val7\n"
            "temp.val8\n"
            "temp.sub.val1\n"
            "temp.sub.val2\n"
            "*temp.sub.valsum\n"
            "temp.multisub.count\n"
            "temp.multisub.a.val1\n"
            "temp.multisub.a.val2\n"
            "*temp.multisub.a.valsum\n"
            "temp.multisub.b.val1\n"
            "temp.multisub.b.val2\n"
            "*temp.multisub.b.valsum\n"
            "*temp.multisub.sum.val1\n"
            "*temp.multisub.sum.val2\n"
            "*temp.multisub.sum.valsum\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].addedmetrics[1]\n"
            "consumer[0].addedmetrics[0] *\n"
    );
        // test adding all using tags
    ASSERT_CONSUMER_MATCH("testAddAll2", std::string(
            "temp.val1\n"
            "temp.val2\n"
            "temp.val3\n"
            "temp.val4\n"
            "temp.val5\n"
            "temp.val6\n"
            "temp.val7\n"
            "temp.val8\n"
            "temp.sub.val1\n"
            "temp.sub.val2\n"
            "*temp.sub.valsum\n"
            "temp.multisub.count\n"
            "temp.multisub.a.val1\n"
            "temp.multisub.a.val2\n"
            "*temp.multisub.a.valsum\n"
            "temp.multisub.b.val1\n"
            "temp.multisub.b.val2\n"
            "*temp.multisub.b.valsum\n"
            "*temp.multisub.sum.val1\n"
            "*temp.multisub.sum.val2\n"
            "*temp.multisub.sum.valsum\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] *\n"
    );
        // Test that all metrics are added when a metricsset is added by name
    ASSERT_CONSUMER_MATCH("testSpecifiedSetName", std::string(
            "temp.sub.val1\n"
            "temp.sub.val2\n"
            "*temp.sub.valsum\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].addedmetrics[1]\n"
            "consumer[0].addedmetrics[0] temp.sub\n"
    );
        // Test that all metrics are added when a metricsset is added by tag
    ASSERT_CONSUMER_MATCH("testSpecifiedSetTag", std::string(
            "temp.sub.val1\n"
            "temp.sub.val2\n"
            "*temp.sub.valsum\n"
            "temp.multisub.a.val1\n"
            "temp.multisub.a.val2\n"
            "*temp.multisub.a.valsum\n"
            "temp.multisub.b.val1\n"
            "temp.multisub.b.val2\n"
            "*temp.multisub.b.valsum\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] sub\n"
    );
        // Test that all metrics are added from the set except those with a
        // certain tag.
    ASSERT_CONSUMER_MATCH("testSpecifiedSetTagWithExceptionTags", std::string(
            "temp.val1\n"
            "temp.val4\n"
            "temp.val7\n"
            "temp.val8\n"
            "temp.sub.val2\n"
            "temp.multisub.count\n"
            "temp.multisub.a.val2\n"
            "temp.multisub.b.val2\n"
            "*temp.multisub.sum.val2\n"
        ),
            "raw:"
            "consumer[1]\n"
            "consumer[0].name consumer\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] test\n"
            "consumer[0].removedtags[2]\n"
            "consumer[0].removedtags[0] tag2\n"
            "consumer[0].removedtags[1] tag4\n"
    );
};

namespace {
    struct FakeTimer : public MetricManager::Timer {
        time_t _time;
        FakeTimer(time_t startTime = 0) : _time(startTime) {}
        time_t getTime() const override { return _time; }
    };

    struct BriefValuePrinter : public MetricVisitor {
        uint32_t count;
        std::ostringstream ost;

        BriefValuePrinter() : count(0), ost() {}

        bool visitMetric(const Metric& metric, bool) override {
            if (++count > 1) ost << ",";
            //ost << metric.getPath() << ":";
            ost << metric.getDoubleValue("value");
            return true;
        }
    };

    bool waitForTimeProcessed(const MetricManager& mm,
                              time_t processtime, uint32_t timeout = 120)
    {
        uint32_t lastchance = time(0) + timeout;
        while (time(0) < lastchance) {
            if (mm.getLastProcessedTime() >= processtime) return true;
            mm.timeChangedNotification();
            FastOS_Thread::Sleep(10);
        }
        return false;
    }

    std::string dumpAllSnapshots(const MetricManager& mm,
                                 const std::string& consumer)
    {
        std::ostringstream ost;
        ost << "\n";
        {
            MetricLockGuard metricLock(mm.getMetricLock());
            BriefValuePrinter briefValuePrinter;
            mm.visit(metricLock, mm.getActiveMetrics(metricLock),
                     briefValuePrinter, consumer);
            ost << "Current: " << briefValuePrinter.ost.str() << "\n";
        }
        {
            MetricLockGuard metricLock(mm.getMetricLock());
            BriefValuePrinter briefValuePrinter;
            mm.visit(metricLock, mm.getTotalMetricSnapshot(metricLock),
                     briefValuePrinter, consumer);
            ost << "Total: " << briefValuePrinter.ost.str() << "\n";
        }
        std::vector<uint32_t> periods;
        {
            MetricLockGuard metricLock(mm.getMetricLock());
            periods = mm.getSnapshotPeriods(metricLock);
        }
        for (uint32_t i=0; i<periods.size(); ++i) {
            MetricLockGuard metricLock(mm.getMetricLock());
            const MetricSnapshotSet& set(mm.getMetricSnapshotSet(
                    metricLock, periods[i]));
            ost << set.getName() << "\n";
            uint32_t count = 0;
            for (uint32_t j=0; j<2; ++j) {
                if (set.getCount() == 1 && j == 1) continue;
                const MetricSnapshot& snap(set.getSnapshot(j == 1));
                BriefValuePrinter briefValuePrinter;
                mm.visit(metricLock, snap, briefValuePrinter, consumer);
                ost << "  " << count++ << " " << &snap.getMetrics() << ": "
                    << briefValuePrinter.ost.str() << "\n";
            }
        }
        return ost.str();
    }

}

#define ASSERT_VALUES(mm, period, expected) \
{ \
    MetricLockGuard lockGuard(mm.getMetricLock()); \
    BriefValuePrinter briefValuePrinter; \
    if (period == -1) { \
        mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), \
                 briefValuePrinter, "snapper"); \
    } else if (period == 0) { \
        mm.visit(lockGuard, mm.getTotalMetricSnapshot(lockGuard), \
                 briefValuePrinter, "snapper"); \
    } else { \
        mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, period), \
                 briefValuePrinter, "snapper"); \
    } \
    CPPUNIT_ASSERT_EQUAL_MSG(dumpAllSnapshots(mm, "snapper"), \
            std::string(expected), briefValuePrinter.ost.str()); \
}

#define ASSERT_PROCESS_TIME(mm, time) \
{ \
    LOG(info, "Waiting for processed time %u.", time); \
    bool gotToCorrectProgress = waitForTimeProcessed(mm, time); \
    if (!gotToCorrectProgress) \
        CPPUNIT_FAIL("Failed to get to processed time within timeout"); \
}

void MetricManagerTest::testSnapshots()
{
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
    TestMetricSet mySet;
    MetricManager mm(std::move(timerImpl));
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }
    mm.init("raw:"
            "consumer[2]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n"
            "consumer[1].name log\n"
            "consumer[1].tags[1]\n"
            "consumer[1].tags[0] snaptest\n",
            pool);
    MetricNameVisitor visitor;
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), visitor, "snapper");
        MetricManager::ConsumerSpec::SP consumerSpec(
            mm.getConsumerSpec(lockGuard, "snapper"));
        CPPUNIT_ASSERT_EQUAL_MSG(consumerSpec.get() ? consumerSpec->toString()
                                                    : "Non-existing consumer",
                                 std::string("\n"
                                     "temp.val6\n"
                                     "temp.sub.val1\n"
                                     "*temp.sub.valsum\n"
                                     "temp.multisub.count\n"
                                     "temp.multisub.a.val1\n"
                                     "*temp.multisub.a.valsum\n"
                                     "temp.multisub.b.val1\n"
                                     "*temp.multisub.b.valsum\n"
                                     "*temp.multisub.sum.val1\n"
                                     "*temp.multisub.sum.val2\n"
                                     "*temp.multisub.sum.valsum\n"
                                 ),
                                 "\n" + visitor.toString());
    }
        // Initially, there should be no metrics logged
    ASSERT_PROCESS_TIME(mm, 1000);
    ASSERT_VALUES(mm, 5 * 60, "");

        // Adding metrics done in first five minutes.
    mySet.val6.addValue(2);
    mySet.val9.val1.addValue(4);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(7);
    mySet.val10.a.val2.addValue(2);
    mySet.val10.b.val1.addValue(1);
    timer->_time += 5 * 60;
    ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60);
    ASSERT_VALUES(mm,  5 * 60, "2,4,4,1,7,9,1,1,8,2,10");
    ASSERT_VALUES(mm, 60 * 60, "");
    ASSERT_VALUES(mm,  0 * 60, "2,4,4,1,7,9,1,1,8,2,10");

        // Adding metrics done in second five minute period. Total should
        // be updated to account for both
    mySet.val6.addValue(4);
    mySet.val9.val1.addValue(5);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(8);
    mySet.val10.a.val2.addValue(3);
    mySet.val10.b.val1.addValue(2);
    timer->_time += 5 * 60;
    ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * 2);
    ASSERT_VALUES(mm,  5 * 60, "4,5,5,1,8,11,2,2,10,3,13");
    ASSERT_VALUES(mm, 60 * 60, "");
    ASSERT_VALUES(mm,  0 * 60, "4,5,5,2,8,11,2,2,10,3,13");

    //std::cerr << dumpAllSnapshots(mm, "snapper") << "\n";

        // Adding another five minute period where nothing have happened.
        // Metric for last 5 minutes should be 0.
    timer->_time += 5 * 60;
    ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * 3);
    ASSERT_VALUES(mm,  5 * 60, "0,0,0,0,0,0,0,0,0,0,0");
    ASSERT_VALUES(mm, 60 * 60, "");
    ASSERT_VALUES(mm,  0 * 60, "4,5,5,2,8,11,2,2,10,3,13");

        // Advancing time to 60 minute period, we should create a proper
        // 60 minute period timer.
    mySet.val6.addValue(6);
    for (uint32_t i=0; i<9; ++i) { // 9 x 5 minutes. Avoid snapshot bumping
                                   // due to taking snapshots in the past
        timer->_time += 5 * 60;
        ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * (4 + i));
    }
    ASSERT_VALUES(mm,  5 * 60, "0,0,0,0,0,0,0,0,0,0,0");
    ASSERT_VALUES(mm, 60 * 60, "6,5,5,2,8,11,2,2,10,3,13");
    ASSERT_VALUES(mm,  0 * 60, "6,5,5,2,8,11,2,2,10,3,13");

        // Test that reset works
    mm.reset(1000);
    ASSERT_VALUES(mm,      -1, "0,0,0,0,0,0,0,0,0,0,0");
    ASSERT_VALUES(mm,  5 * 60, "0,0,0,0,0,0,0,0,0,0,0");
    ASSERT_VALUES(mm, 60 * 60, "0,0,0,0,0,0,0,0,0,0,0");
    ASSERT_VALUES(mm,  0 * 60, "0,0,0,0,0,0,0,0,0,0,0");
}

void MetricManagerTest::testPrintUtils()
{
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
    MetricManager mm(std::move(timerImpl));
    TestMetricSet mySet;
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }
        // Adding metrics to have some values in them
    mySet.val6.addValue(2);
    mySet.val9.val1.addValue(4);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(7);
    mySet.val10.a.val2.addValue(2);
    mySet.val10.b.val1.addValue(1);
        // Initialize metric manager to get snapshots created.
    mm.init("raw:"
            "consumer[2]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n"
            "consumer[1].name log\n"
            "consumer[1].tags[1]\n"
            "consumer[1].tags[0] snaptest\n",
            pool);
    using namespace printutils;
    MetricLockGuard lockGuard(mm.getMetricLock());
    MetricSource source(mm.getActiveMetrics(lockGuard),
                        "temp.multisub");
    CPPUNIT_ASSERT(source.getMetric("count") != 0);
    CPPUNIT_ASSERT(source.getMetric("a.val1") != 0);
    CPPUNIT_ASSERT(source.getMetric("a.valsum") != 0);
    CPPUNIT_ASSERT(source.getMetric("sum.val1") != 0);
    CPPUNIT_ASSERT(source.getMetric("sum.valsum") != 0);

    std::vector<Metric::String> metrics(
            source.getPathsMatchingPrefix("a.val"));
    std::vector<Metric::String> expected;
    expected.push_back("val1");
    expected.push_back("val2");
    expected.push_back("valsum");
    CPPUNIT_ASSERT_EQUAL(expected, metrics);

    HttpTable table("mytable", "stuff");
    table.colNames.push_back("values");
    table.rowNames.push_back("valsum");
    table[0][0] = getValueString(
              getLongMetric("a.val1.value", source)
            + getLongMetric("a.val2.value", source));
    std::ostringstream ost;
    table.print(ost);
    CPPUNIT_ASSERT_EQUAL(std::string(
                "<h3>mytable</h3>\n"
                "<table border=\"1\">\n"
                "<tr><th>stuff</th><th>values</th></tr>\n"
                "<tr><td>valsum</td><td align=\"right\">9</td></tr>\n"
                "</table>\n"
            ), ost.str());
}

void MetricManagerTest::testXmlOutput()
{
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
    MetricManager mm(std::move(timerImpl));
    TestMetricSet mySet;
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }

    // Initialize metric manager to get snapshots created.
    mm.init("raw:"
            "consumer[2]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n"
            "consumer[1].name log\n"
            "consumer[1].tags[1]\n"
            "consumer[1].tags[0] snaptest\n",
            pool);

    mm.takeSnapshots(mm.getMetricLock(), 1000);

    // Adding metrics to have some values in them
    mySet.val6.addValue(2);
    mySet.val9.val1.addValue(4);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(7);
    mySet.val10.a.val2.addValue(2);
    mySet.val10.b.val1.addValue(1);

    timer->_time = 1300;
    mm.takeSnapshots(mm.getMetricLock(), 1300);

    std::string expected(
            "'<snapshot name=\"5 minute\" from=\"1000\" to=\"1300\" period=\"300\">\n"
            "  <temp>\n"
            "    <val6 average=\"2\" last=\"2\" min=\"2\" max=\"2\" count=\"1\"/>\n"
            "    <sub>\n"
            "      <val1 average=\"4\" last=\"4\" min=\"4\" max=\"4\" count=\"1\"/>\n"
            "      <valsum average=\"4\" last=\"4\" min=\"4\" max=\"4\" count=\"1\"/>\n"
            "    </sub>\n"
            "    <multisub>\n"
            "      <count count=\"1\"/>\n"
            "      <a>\n"
            "        <val1 average=\"7\" last=\"7\" min=\"7\" max=\"7\" count=\"1\"/>\n"
            "        <valsum average=\"9\" last=\"9\"/>\n"
            "      </a>\n"
            "      <b>\n"
            "        <val1 average=\"1\" last=\"1\" min=\"1\" max=\"1\" count=\"1\"/>\n"
            "        <valsum average=\"1\" last=\"1\" min=\"1\" max=\"1\" count=\"1\"/>\n"
            "      </b>\n"
            "      <sum>\n"
            "        <val1 average=\"8\" last=\"8\"/>\n"
            "        <val2 average=\"2\" last=\"2\" min=\"2\" max=\"2\" count=\"1\"/>\n"
            "        <valsum average=\"10\" last=\"10\"/>\n"
            "      </sum>\n"
            "    </multisub>\n"
            "  </temp>\n"
            "</snapshot>'");

    std::ostringstream ost;
    vespalib::XmlOutputStream xos(ost, "  ");
    XmlWriter writer(xos, 300, 0);
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300, false),
                 writer, "snapper");
    }
    std::string actual(ost.str());
    // Not bothering to match all the nitty gritty details as it will test
    // more than it needs to. Just be here in order to check on XML output
    // easily if needed.
    CPPUNIT_ASSERT_EQUAL(expected, "'" + actual + "'");
}

void MetricManagerTest::testJsonOutput()
{
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
    MetricManager mm(std::move(timerImpl));
    TestMetricSet mySet;
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }

    // Initialize metric manager to get snapshots created.
    mm.init("raw:"
            "consumer[1]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n",
            pool);

    mm.takeSnapshots(mm.getMetricLock(), 1000);

    // Adding metrics to have some values in them
    mySet.val6.addValue(2);
    mySet.val9.val1.addValue(4);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(7);
    mySet.val10.a.val2.addValue(2);
    mySet.val10.b.val1.addValue(1);

    timer->_time = 1300;
    mm.takeSnapshots(mm.getMetricLock(), 1300);

        // Create json output
    vespalib::asciistream as;
    vespalib::JsonStream jsonStream(as);
    JsonWriter writer(jsonStream);
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300, false),
                 writer, "snapper");
    }
    jsonStream.finalize();
    std::string jsonData = as.str();
        // Parse it back
    using namespace vespalib::slime;
    vespalib::Slime slime;
    size_t parsed = JsonFormat::decode(vespalib::Memory(jsonData), slime);
    if (jsonData.size() != parsed) {
        vespalib::SimpleBuffer buffer;
        JsonFormat::encode(slime, buffer, false);
        std::ostringstream ost;
        ost << "Failed to parse JSON: '\n"
            << jsonData << "'\n:" << buffer.get().make_string() << "\n";
        CPPUNIT_ASSERT_EQUAL_MSG(ost.str(), jsonData.size(), parsed);
    }
        // Verify some content
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 1000.0,
            slime.get()["snapshot"]["from"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 1300.0,
            slime.get()["snapshot"]["to"].asDouble());

    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, vespalib::string("temp.val6"),
            slime.get()["values"][0]["name"].asString().make_string());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, vespalib::string("val6 desc"),
            slime.get()["values"][0]["description"].asString().make_string());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 2.0,
            slime.get()["values"][0]["values"]["average"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 1.0,
            slime.get()["values"][0]["values"]["count"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 2.0,
            slime.get()["values"][0]["values"]["min"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 2.0,
            slime.get()["values"][0]["values"]["max"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 2.0,
            slime.get()["values"][0]["values"]["last"].asDouble());

    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, vespalib::string("temp.multisub.sum.valsum"),
            slime.get()["values"][10]["name"].asString().make_string());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, vespalib::string("valsum desc"),
            slime.get()["values"][10]["description"].asString().make_string());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 10.0,
            slime.get()["values"][10]["values"]["average"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 3.0,
            slime.get()["values"][10]["values"]["count"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 1.0,
            slime.get()["values"][10]["values"]["min"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 7.0,
            slime.get()["values"][10]["values"]["max"].asDouble());
    CPPUNIT_ASSERT_EQUAL_MSG(jsonData, 10.0,
            slime.get()["values"][10]["values"]["last"].asDouble());


    metrics::StateApiAdapter adapter(mm);
    vespalib::string normal = adapter.getMetrics("snapper");
    CPPUNIT_ASSERT_EQUAL(vespalib::string(jsonData), normal);
    vespalib::string total = adapter.getTotalMetrics("snapper");
    CPPUNIT_ASSERT(total.size() > 0);
    CPPUNIT_ASSERT(total != normal);
}

namespace {

struct MetricSnapshotTestFixture
{
    static const size_t DEFAULT_THREAD_STACK_SIZE = 256 * 1024;

    MetricManagerTest& test;
    FastOS_ThreadPool pool;
    FakeTimer* timer;
    MetricManager manager;
    MetricSet& mset;

    MetricSnapshotTestFixture(MetricManagerTest& callerTest, MetricSet& metricSet)
        : test(callerTest),
          pool(DEFAULT_THREAD_STACK_SIZE),
          timer(new FakeTimer(1000)),
          manager(std::unique_ptr<MetricManager::Timer>(timer)),
          mset(metricSet)
    {
        {
            MetricLockGuard lockGuard(manager.getMetricLock());
            manager.registerMetric(lockGuard, mset);
        }

        // Initialize metric manager to get snapshots created.
        manager.init(
                "raw:"
                "consumer[1]\n"
                "consumer[0].name snapper\n"
                "consumer[0].addedmetrics[1]\n"
                "consumer[0].addedmetrics[0] *\n",
                pool);

        test.takeSnapshots(manager, 1000);
    }

    // Take snapshot of metric values from time 1000 to time 1300
    void takeSnapshotsOnce() {
        timer->_time = 1300;
        test.takeSnapshots(manager, 1300);
    }

    std::string renderLastSnapshotAsJson() const {
        vespalib::asciistream as;
        vespalib::JsonStream jsonStream(as, true);
        JsonWriter writer(jsonStream);
        {
            MetricLockGuard lockGuard(manager.getMetricLock());
            manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false),
                          writer, "snapper");
        }
        jsonStream.finalize();
        return as.str();
    }

    std::string renderLastSnapshotAsText(
            const std::string& matchPattern = ".*") const
    {
        std::ostringstream ss;
        TextWriter writer(ss, 300, matchPattern, true);
        {
            MetricLockGuard lockGuard(manager.getMetricLock());
            manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false),
                          writer, "snapper");
        }
        return ss.str();
    }
};

class JsonMetricWrapper
{
    std::string _jsonText;
    vespalib::Slime _tree;
public:
    JsonMetricWrapper(const std::string& jsonText);
    ~JsonMetricWrapper();

    // XXX ideally all these should be const, but is not clear how/if it's
    // possible to get a const cursor into the underlying tree.
    vespalib::slime::Cursor& root() { return _tree.get(); }

    vespalib::slime::Cursor& nthMetric(size_t metricIndex) {
        return root()["values"][metricIndex];
    }

    size_t nthMetricDimensionCount(size_t metricIndex) {
        return nthMetric(metricIndex)["dimensions"].children();
    }

    std::string nthMetricName(size_t metricIndex) {
       return nthMetric(metricIndex)["name"].asString().make_string();
    }

    std::string nthMetricDimension(size_t metricIndex, const std::string& key) {
        return nthMetric(metricIndex)["dimensions"][key]
                .asString().make_string();
    }

    // Verify that the nth metric has the given name and the given set of 
    // dimension key-values. Cannot use name alone to check, as multiple metrics
    // may have same name but different dimensions and output ordering of
    // metrics is well defined as being that of the insertion order.
    void verifyDimensions(size_t metricIndex,
                          const std::string& name,
                          const Metric::Tags& dimensions) {
        // Works to do this outside of main test body because cppunit uses
        // exceptions for its failures.
        CPPUNIT_ASSERT_EQUAL_MSG(_jsonText, name, nthMetricName(metricIndex));
        CPPUNIT_ASSERT_EQUAL_MSG(_jsonText, dimensions.size(),
                                 nthMetricDimensionCount(metricIndex));
        for (auto& dim : dimensions) {
            CPPUNIT_ASSERT_EQUAL_MSG(_jsonText, std::string(dim.value),
                                     nthMetricDimension(metricIndex, dim.key));
        }
    }
};

JsonMetricWrapper::JsonMetricWrapper(const std::string& jsonText)
    : _jsonText(jsonText)
{
    vespalib::slime::JsonFormat::decode(vespalib::Memory(jsonText), _tree);
}
JsonMetricWrapper::~JsonMetricWrapper() { }

struct DimensionTestMetricSet : MetricSet
{
    DoubleValueMetric val1;
    LongCountMetric val2;

    DimensionTestMetricSet(MetricSet* owner = nullptr);
    ~DimensionTestMetricSet();
};

DimensionTestMetricSet::DimensionTestMetricSet(MetricSet* owner)
    : MetricSet("temp", {{"foo", "megafoo"}, {"bar", "hyperbar"}}, "", owner),
      val1("val1", "tag1", "val1 desc", this),
      val2("val2", {{"baz", "superbaz"}}, "val2 desc", this)
{ }
DimensionTestMetricSet::~DimensionTestMetricSet() { }

} // anon ns

void
MetricManagerTest::jsonOutputSupportsMultipleDimensions()
{
    DimensionTestMetricSet mset;
    MetricSnapshotTestFixture fixture(*this, mset);

    mset.val1.addValue(2);
    mset.val2.inc();

    fixture.takeSnapshotsOnce();
    std::string actual = fixture.renderLastSnapshotAsJson();
    JsonMetricWrapper json(actual);

    json.verifyDimensions(0, "temp.val1",
                          {{"foo", "megafoo"}, {"bar", "hyperbar"}});
    json.verifyDimensions(1, "temp.val2",
                          {{"foo", "megafoo"}, {"bar", "hyperbar"},
                           {"baz", "superbaz"}});
}

namespace {

struct NestedDimensionTestMetricSet : MetricSet
{
    DimensionTestMetricSet nestedSet;

    NestedDimensionTestMetricSet()
        : MetricSet("outer", {{"fancy", "stuff"}}, ""),
          nestedSet(this)
    {
    }
};

} // anon ns

void
MetricManagerTest::jsonOutputCanNestDimensionsFromMultipleMetricSets()
{
    NestedDimensionTestMetricSet mset;
    MetricSnapshotTestFixture fixture(*this, mset);

    mset.nestedSet.val1.addValue(2);
    mset.nestedSet.val2.inc();

    fixture.takeSnapshotsOnce();
    std::string actual = fixture.renderLastSnapshotAsJson();
    JsonMetricWrapper json(actual);

    json.verifyDimensions(0, "outer.temp.val1",
                          {{"foo", "megafoo"}, {"bar", "hyperbar"},
                           {"fancy", "stuff"}});
    json.verifyDimensions(1, "outer.temp.val2",
                          {{"foo", "megafoo"}, {"bar", "hyperbar"},
                           {"baz", "superbaz"}, {"fancy", "stuff"}});
}

namespace {

struct DimensionOverridableTestMetricSet : MetricSet
{
    DoubleValueMetric val;

    DimensionOverridableTestMetricSet(const std::string& dimValue,
                                MetricSet* owner = nullptr)
        : MetricSet("temp", {{"foo", dimValue}}, "", owner),
          val("val", "", "val desc", this)
    { }
};

struct SameNamesTestMetricSet : MetricSet
{
    DimensionOverridableTestMetricSet set1;
    DimensionOverridableTestMetricSet set2;

    SameNamesTestMetricSet();
    ~SameNamesTestMetricSet();
};

SameNamesTestMetricSet::SameNamesTestMetricSet()
    : MetricSet("outer", {{"fancy", "stuff"}}, ""),
      set1("bar", this),
      set2("baz", this)
{ }
SameNamesTestMetricSet::~SameNamesTestMetricSet() { }

} // anon ns

void
MetricManagerTest::jsonOutputCanHaveMultipleSetsWithSameName()
{
    SameNamesTestMetricSet mset;
    MetricSnapshotTestFixture fixture(*this, mset);

    mset.set1.val.addValue(2);
    mset.set2.val.addValue(5);

    fixture.takeSnapshotsOnce();
    std::string actual = fixture.renderLastSnapshotAsJson();
    JsonMetricWrapper json(actual);

    // Note the identical names. Only difference is the dimensions per set.
    json.verifyDimensions(0, "outer.temp.val",
                          {{"foo", "bar"}, {"fancy", "stuff"}});
    json.verifyDimensions(1, "outer.temp.val",
                          {{"foo", "baz"}, {"fancy", "stuff"}});
}

void MetricManagerTest::testTextOutput()
{
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
    MetricManager mm(std::move(timerImpl));
    TestMetricSet mySet;
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }
        // Adding metrics to have some values in them
    mySet.val6.addValue(2);
    mySet.val9.val1.addValue(4);
    mySet.val10.count.inc();
    mySet.val10.a.val1.addValue(7);
    mySet.val10.a.val2.addValue(2);
    mySet.val10.b.val1.addValue(1);
        // Initialize metric manager to get snapshots created.
    mm.init("raw:"
            "consumer[2]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n"
            "consumer[1].name log\n"
            "consumer[1].tags[1]\n"
            "consumer[1].tags[0] snaptest\n",
            pool);
    std::string expected(
        "snapshot \"Active metrics showing updates since last snapshot\" from 1000 to 0 period 0\n"
        "temp.val6 average=2 last=2 min=2 max=2 count=1 total=2\n"
        "temp.sub.val1 average=4 last=4 min=4 max=4 count=1 total=4\n"
        "temp.sub.valsum average=4 last=4 min=4 max=4 count=1 total=4\n"
        "temp.multisub.count count=1\n"
        "temp.multisub.a.val1 average=7 last=7 min=7 max=7 count=1 total=7\n"
        "temp.multisub.a.valsum average=9 last=9\n"
        "temp.multisub.b.val1 average=1 last=1 min=1 max=1 count=1 total=1\n"
        "temp.multisub.b.valsum average=1 last=1 min=1 max=1 count=1 total=1\n"
        "temp.multisub.sum.val1 average=8 last=8\n"
        "temp.multisub.sum.val2 average=2 last=2 min=2 max=2 count=1 total=2\n"
        "temp.multisub.sum.valsum average=10 last=10");
    std::ostringstream ost;
    TextWriter writer(ost, 300, ".*", true);
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), writer, "snapper");
    }
    std::string actual(ost.str());
    // Not bothering to match all the nitty gritty details as it will test
    // more than it needs to. Just be here in order to check on XML output
    // easily if needed.
    CPPUNIT_ASSERT_EQUAL(expected, actual);
}

void
MetricManagerTest::textOutputSupportsDimensions()
{
    NestedDimensionTestMetricSet mset;
    MetricSnapshotTestFixture fixture(*this, mset);

    mset.nestedSet.val1.addValue(2);
    mset.nestedSet.val2.inc();

    fixture.takeSnapshotsOnce();
    std::string actual = fixture.renderLastSnapshotAsText("outer.*temp.*val");
    std::string expected(
            "snapshot \"5 minute\" from 1000 to 1300 period 300\n"
            "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val1 "
                "average=2 last=2 min=2 max=2 count=1 total=2\n"
            "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val2"
                "{baz:superbaz} count=1");
    CPPUNIT_ASSERT_EQUAL(expected, actual);
}

namespace {
    struct MyUpdateHook : public UpdateHook {
        std::ostringstream& _output;
        FakeTimer& _timer;

        MyUpdateHook(std::ostringstream& output, const char* name,
                     FakeTimer& timer)
            : UpdateHook(name), _output(output), _timer(timer) {}

        void updateMetrics(const MetricLockGuard & ) override {
            _output << _timer.getTime() << ": " << getName() << " called\n";
        }
    };
}

void MetricManagerTest::testUpdateHooks()
{
    std::ostringstream output;
    FastOS_ThreadPool pool(256 * 1024);
    FakeTimer* timer = new FakeTimer(1000);
    std::unique_ptr<MetricManager::Timer> timerImpl(timer);
        // Add a metric set just so one exist
    TestMetricSet mySet;
    MetricManager mm(std::move(timerImpl));
    {
        MetricLockGuard lockGuard(mm.getMetricLock());
        mm.registerMetric(lockGuard, mySet.set);
    }

    MyUpdateHook preInitShort(output, "BIS", *timer);
    MyUpdateHook preInitLong(output, "BIL", *timer);
    MyUpdateHook preInitInfinite(output, "BII", *timer);
    mm.addMetricUpdateHook(preInitShort, 5);
    mm.addMetricUpdateHook(preInitLong, 300);
    mm.addMetricUpdateHook(preInitInfinite, 0);

    // All hooks should get called during initialization

        // Initialize metric manager to get snapshots created.
    output << "Running init\n";
    mm.init("raw:"
            "consumer[2]\n"
            "consumer[0].name snapper\n"
            "consumer[0].tags[1]\n"
            "consumer[0].tags[0] snaptest\n"
            "consumer[1].name log\n"
            "consumer[1].tags[1]\n"
            "consumer[1].tags[0] snaptest\n",
            pool);
    output << "Init done\n";

    MyUpdateHook postInitShort(output, "AIS", *timer);
    MyUpdateHook postInitLong(output, "AIL", *timer);
    MyUpdateHook postInitInfinite(output, "AII", *timer);
    mm.addMetricUpdateHook(postInitShort, 5);
    mm.addMetricUpdateHook(postInitLong, 400);
    mm.addMetricUpdateHook(postInitInfinite, 0);

    // After 5 seconds the short ones should get another.

    timer->_time = 1006;
    waitForTimeProcessed(mm, 1006);

    // After 4 more seconds the short ones should get another
    // since last update was a second late. (Stable periods, process time
    // should not affect how often they are updated)

    timer->_time = 1010;
    waitForTimeProcessed(mm, 1010);

    // Bumping considerably ahead, such that next update is in the past,
    // we should only get one update called in this period.

    timer->_time = 1200;
    waitForTimeProcessed(mm, 1200);

    // No updates at this time.
    timer->_time = 1204;
    waitForTimeProcessed(mm, 1204);

    // Give all hooks an update
    mm.updateMetrics(true);

    // Last update should not have interfered with periods
    timer->_time = 1205;
    waitForTimeProcessed(mm, 1205);

    // Time is just ahead of a snapshot.
    timer->_time = 1299;
    waitForTimeProcessed(mm, 1299);

    // At time 1300 we are at a 5 minute snapshot bump
    // All hooks should thus get an update. The one with matching period
    // should only get one
    timer->_time = 1300;
    waitForTimeProcessed(mm, 1300);

    // The snapshot time currently doesn't count for the metric at period
    // 400. It will get an event at this time.
    timer->_time = 1450;
    waitForTimeProcessed(mm, 1450);

    std::string expected(
        "Running init\n"
        "1000: BIS called\n"
        "1000: BIL called\n"
        "Init done\n"
        "1006: BIS called\n"
        "1006: AIS called\n"
        "1010: BIS called\n"
        "1010: AIS called\n"
        "1200: BIS called\n"
        "1200: AIS called\n"
        "1204: BIS called\n"
        "1204: BIL called\n"
        "1204: AIS called\n"
        "1204: AIL called\n"
        "1204: BII called\n"
        "1204: AII called\n"
        "1205: BIS called\n"
        "1205: AIS called\n"
        "1299: BIS called\n"
        "1299: AIS called\n"
        "1300: BIS called\n"
        "1300: BIL called\n"
        "1300: AIS called\n"
        "1300: AIL called\n"
        "1300: BII called\n"
        "1300: AII called\n"
        "1450: BIS called\n"
        "1450: AIS called\n"
        "1450: AIL called\n"
    );
    std::string actual(output.str());
    CPPUNIT_ASSERT_EQUAL(expected, actual);
}

} // metrics
